Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

MongoInterruptedException's msg and its stacktrace handling fix in BenchmarkCommand's worker threads #16

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

MongoInterruptedException's msg and its stacktrace handling fix in BenchmarkCommand's worker threads #16

wants to merge 1 commit into from

Conversation

v1k1nghawk
Copy link

@v1k1nghawk v1k1nghawk commented Nov 30, 2022 •
edited
Loading

Each successful benchmark's run currently ends with this output from each BenchmarkCommand's worker Runnable caused by their interruption:

...
at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695)
        at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:457)
        at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:401)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:695)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:161)
        at com.mongodb.DBCursor.initializeCursor(DBCursor.java:896)
        at com.mongodb.DBCursor.hasNext(DBCursor.java:148)
        at com.mongodb.socialite.users.DefaultUserService.getUsersFromCursor(DefaultUserService.java:597)
        at com.mongodb.socialite.users.DefaultUserService.getFollowing(DefaultUserService.java:176)
        at com.mongodb.socialite.feed.FanoutOnRead.getFeedFor(FanoutOnRead.java:46)
        at com.mongodb.socialite.resources.UserResource.getTimeline(UserResource.java:153)
        at com.mongodb.socialite.benchmark.traffic.TrafficModel.next(TrafficModel.java:151)
        at com.mongodb.socialite.cli.BenchmarkCommand$1.run(BenchmarkCommand.java:217)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.InterruptedException
        at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1343)
        at java.base/java.util.concurrent.Semaphore.acquire(Semaphore.java:318)
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:199)
        ... 40 more
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:203)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:123)
        at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:78)
        at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:85)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:562)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289)
        at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
        at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
        at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
        at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
        at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
        at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695)
        at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:457)
        at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:401)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:695)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:161)
        at com.mongodb.DBCursor.initializeCursor(DBCursor.java:896)
        at com.mongodb.DBCursor.hasNext(DBCursor.java:148)
        at com.mongodb.socialite.users.DefaultUserService.getUsersFromCursor(DefaultUserService.java:597)
        at com.mongodb.socialite.users.DefaultUserService.getFollowing(DefaultUserService.java:176)
        at com.mongodb.socialite.feed.FanoutOnRead.getFeedFor(FanoutOnRead.java:46)
        at com.mongodb.socialite.resources.UserResource.getTimeline(UserResource.java:153)
        at com.mongodb.socialite.benchmark.traffic.TrafficModel.next(TrafficModel.java:151)
        at com.mongodb.socialite.cli.BenchmarkCommand$1.run(BenchmarkCommand.java:217)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.InterruptedException
        at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1343)
        at java.base/java.util.concurrent.Semaphore.acquire(Semaphore.java:318)
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:199)
        ... 40 more
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
INFO  [2022-11-25 16:57:48,570] org.mongodb.driver.connection: Closed connection [connectionId{localValue:33}] to 172.31.29.190:27017 because there was a socket exception raised by this connection.
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:203)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:123)
        at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:78)
        at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:85)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:562)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289)
        at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
        at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
        at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
        at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
        at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
        at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695)
        at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:457)
        at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:401)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:695)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:161)
        at com.mongodb.DBCursor.initializeCursor(DBCursor.java:896)
        at com.mongodb.DBCursor.hasNext(DBCursor.java:148)
        at com.mongodb.socialite.content.DefaultContentService.getFromCursor(DefaultContentService.java:126)
        at com.mongodb.socialite.content.DefaultContentService.getContentFor(DefaultContentService.java:93)
        at com.mongodb.socialite.feed.FanoutOnRead.getFeedFor(FanoutOnRead.java:47)
        at com.mongodb.socialite.resources.UserResource.getTimeline(UserResource.java:153)
        at com.mongodb.socialite.benchmark.traffic.TrafficModel.next(TrafficModel.java:155)
        at com.mongodb.socialite.cli.BenchmarkCommand$1.run(BenchmarkCommand.java:217)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.InterruptedException
        at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1343)
        at java.base/java.util.concurrent.Semaphore.acquire(Semaphore.java:318)
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:199)
        ... 40 more
...
INFO  [2022-11-25 16:57:50,172] com.mongodb.socialite.ServiceManager: Stopping configured services
INFO  [2022-11-25 16:57:50,182] com.mongodb.socialite.ServiceManager: All services shut down successfully

As far as this interruption is part of the designed stopping mechanics, my proposal is to suppress the output of MongoInterruptedException and especially its stacktrace in BenchmarkCommand's worker threads.
After this fix, the successful output looks like this:

...
scroll_timeline
             count = 2415
         mean rate = 40.25 calls/second
     1-minute rate = 41.36 calls/second
     5-minute rate = 43.14 calls/second
    15-minute rate = 43.57 calls/second
               min = 0.78 milliseconds
               max = 37.49 milliseconds
              mean = 1.59 milliseconds
            stddev = 1.59 milliseconds
            median = 1.26 milliseconds
              75% <= 1.62 milliseconds
              95% <= 2.76 milliseconds
              98% <= 3.54 milliseconds
              99% <= 9.03 milliseconds
            99.9% <= 36.81 milliseconds
send_content
             count = 258
         mean rate = 4.30 calls/second
     1-minute rate = 4.19 calls/second
     5-minute rate = 4.05 calls/second
    15-minute rate = 4.02 calls/second
               min = 1.53 milliseconds
               max = 85.90 milliseconds
              mean = 3.52 milliseconds
            stddev = 6.14 milliseconds
            median = 2.68 milliseconds
              75% <= 3.20 milliseconds
              95% <= 4.99 milliseconds
              98% <= 6.49 milliseconds
              99% <= 36.67 milliseconds
            99.9% <= 85.90 milliseconds
unfollow
             count = 47
         mean rate = 0.78 calls/second
     1-minute rate = 0.66 calls/second
     5-minute rate = 0.47 calls/second
    15-minute rate = 0.42 calls/second
               min = 1.17 milliseconds
               max = 4.21 milliseconds
              mean = 2.11 milliseconds
            stddev = 0.54 milliseconds
            median = 1.97 milliseconds
              75% <= 2.26 milliseconds
              95% <= 3.57 milliseconds
              98% <= 4.21 milliseconds
              99% <= 4.21 milliseconds
            99.9% <= 4.21 milliseconds


INFO  [2022-11-29 14:53:13,219] com.mongodb.socialite.cli.BenchmarkCommand: Test done. Shutting down...
INFO  [2022-11-29 14:53:13,223] com.mongodb.socialite.ServiceManager: Stopping configured services
INFO  [2022-11-29 14:53:13,228] com.mongodb.socialite.ServiceManager: All services shut down successfully

@v1k1nghawk
disabled output with MongoInterruptedException's msg and its stacktra…
73338ed 
…ce during worker thread's stop in BenchmarkCommand
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
1 participant
@v1k1nghawk